SGI Developer Toolbox 6.1

home *** CD-ROM | disk | FTP | other *** search

/ SGI Developer Toolbox 6.1 / SGI Developer Toolbox 6.1 - Disc 4.iso / src / swtools / XandSysPerf / UsingXscope.text < prev next >

Wrap

Text File | 1994-08-02 | 16.8 KB | 377 lines

Engineers concerned about performance, Performance is the buzz-word now at SGI. The question has been asked "Where can you find bloat?" The joke answer is "Anywhere you look." It's funny for about one second. There real question is how do you locate the bloat itself. A program's start up time or its memory usage is just a symptom; you've got to find the causes if you want to find the cures. This posting describes how to find and hunt down program bloat in X Window System clients. The hope is that this information will arm individual engineers with the tools they need to first find and then eliminate the bloat in their X applications. The primary tool used for determining how your application is using X is "xscope" found in the x_eoe.sw.Xapps subsystem. xscope is an X protocol trace gatherer. It acts as a pseudo-server between the X client and the X server. It watches X protocol can prints the decoded X protocol stream to stdout. The following diagram should explain how xscope works: /-----------\ /--------\ /--------\ | | X requests | | X requests | | | arbitrary | ------------> | | ------------> | | | X client | <------------ | xscope | <------------ | Xsgi | | | X events, | | X events, | | | | errors, | | errors, | | \-----------/ replies \--------/ replies \--------/ | | v decoded X protocol trace There is a man page on xscope but here is a brief example you can use to generate an X protocol trace: 1) start a shell 2) assuming you want to connect the machine foobar, set your DISPLAY environment variable to foobar:0 2) run "xscope |& tee XProtoTrace" (XXX csh command) 3) start a second shell 4) in that second shell, set your DISPLAY environment variable to foobar:1 (xscope will act to pass X protocol from foobar's display 1 to the real X server's display 0). 5) now start up your X client 6) once the X application is fully started, Control-C it 7) now Control-C the xscope 8) the file "XProtoTrace" now contains an X protocol trace for your client starting up Now you can examime the X protocol trace and understand what your program is doing at the X protocol level. It helps to be familar with the X protocol. To help you understand the X protocol, I recommend you having the O'Reilly "X Protocol Reference Manual (Volume 0)" nearby. In particular, Appendix I will help you map between X protocol requests and Xlib C routines that generate X protocol. Decoding X protocol is the window system equivalent of system call tracing for normal C programs. The mapping between Xlib and the X protocol is fairly straightforward so if you are familar with Xlib, seeing the protocol shouldn't be too daunting. The first thing to do is "vi XProtoTrace" and look through it. Here's the start of an X protocol trace from xlogo: ------------------------------------------------------------------------------------ 0.00: Client --> 12 bytes byte-order: MSB first major-version: 000b minor-version: 0000 0.04: 520 bytes <-- X11 Server protocol-major-version: 000b protocol-minor-version: 0000 release-number: 00001388 resource-id-base: 0b800000 resource-id-mask: 003fffff motion-buffer-size: 00000000 image-byte-order: MSB first bitmap-format-bit-order: MSB first bitmap-format-scanline-unit: 20 bitmap-format-scanline-pad: 20 min-keycode: 10 (^J) max-keycode: 118 (v) vendor: "Silicon Graphics" pixmap-formats: (4) roots: (2) 0.05: Client --> 84 bytes ............REQUEST: CreateGC graphic-context-id: GXC 0b800000 drawable: DWB 0000002a value-mask: background value-list: background: 00000007 ............REQUEST: CreateGC graphic-context-id: GXC 0b800001 drawable: DWB 0000002c value-mask: background value-list: background: 00000007 ............REQUEST: QueryExtension name: "BIG-REQUESTS" ............REQUEST: GetProperty delete: False window: WIN 0000002a property: <RESOURCE_MANAGER> type: <STRING> long-offset: 00000000 0.10: 104 bytes <-- X11 Server ..............REPLY: QueryExtension present: False major-opcode: 00 first-event: 00 first-error: 00 ..............REPLY: GetProperty format: 08 type: <STRING> bytes-after: 00000000 value: "xcalc*Command.ShapeStyle:^Irectangle ^J" ------------------------------------------------------------------------------------ Notice the way the output says "Client -->" and "<-- X11 Server". That indicates who is saying what. Clients make requests. The X server returns replies (for those requests that return replies), events, and errors. CreateGC is a request without a reply. QueryExtension is a request that returns a reply. Browse through the output of an X protocol trace and get comfortable with the format. To get a high level statistical overview of what the X protocol trace contains, I've written a shell/awk script that does the trick. You can find a copy in this directory (~4Dgifts/toolbox/src/swtools/perf). To use the script say "xprotostats < XProtoTrace". Here is some sample output for iconbook's startup from the 5.1.2 alpha 60: ------------------------------------------------------------------------------------ hoot:/usr/people/mjk#54 -> xprotostats < ICONBOOK RAW CLIENT PROTOCOL STATISITICS: bytes written: 41488 batches written: 409 requests made: 1850 RAW SERVER PROTOCOL STATISITICS: bytes written: 74412 batches written: 419 replies made: 420 events sent: 104 errors sent: 0 COMPUTED STATISTICS: replies/request: 22.70 % server/client data: 179.36 % bytes/request: 22.43 bytes OFTEN MISUSED ROUND-TRIP REQUESTS: AllocColor 42 AllocNamedColor 8 GetGeometry 30 GetInputFocus 30 GetKeyboardMapping 17 GetSelectionOwner 2 GetWindowAttributes 20 InternAtom 49 ListFonts 3 ListProperties 3 QueryBestSize 1 QueryColors 170 QueryExtension 3 QueryFont 10 QueryTree 2 TranslateCoordinates 1 OFTEN MISUSED EVENTS: NoExposure 31 hoot:/usr/people/mjk#55 -> ------------------------------------------------------------------------------------ So what does this mean? How does one target bloat using this output? Here are some observations I've made from the ouput: 1) Notice that the server writes 72.7 kilobytes to the client but the client only sends 40.5 kilobytes to the server. That's pretty lop-sided. Examining the protocol trace with an editor, there are a bunch of explanations: o Motif makes 17 GetKeyboardMapping requests. Each one returns the *same* 904 byte reply. There's 15 kilobytes right there. Only such call is necessary. o Examining the QueryFont requests, the "fixed" font is queried 3 times (once as "Fixed"; twice as "fixed"). Each query reply is 2.87 kilobytes. o There are lots of XQueryColors requests being done querying the color of a single pixel. It takes 12 bytes to issue the request but the reply is 40 bytes. Most of the calls are really unncessary and shift the IO burden to the X server. Probably about ~3 kilobytes. o Some of the size is understandable because I happen to have a rather large ~/.Xresources file that gets placed on the root window's RESOURCE_MANAGER property and must be downloaded to every client. This is about 4.4 kilobytes. 2) Notice the 31 NoExposure events. These are generated by CopyArea or CopyPlane requests to indicate that the copy was successful (if your copy operation involved obscured regions of windows, Graphics Expose events tell you the regions unavaiable for copying). For iconbook, all the CopyAreas done from pixmaps to windows. Pixmaps never are obscured so the NoExposure can always be assumed. You can configure the graphics context used with CopyArea to not generate GraphicsExpose and NoExposure events altogether. This should be done when you _know_ the source drawable is a pixmap. Generating useless events forces your client to wake up unnecessarily. A bad example of this is fm (used to?) generate its blinking cursor using CopyArea from a pixmap. Everytime the cursor blinked, the app would later be woken up again to get the unnnecessary NoExposure event. So if the cursor needed to blink once a second, the app would have to be scheduled twice that often. 3) Notice the 49 InternAtom requests. Each is a round-trip to the server. Realize that a round-trip requites the client to write a request, be descheduled, the X server to be scheduled, the X server to read, and then process the request, write the reply, be descheduled, and reschedule the client so it can read the reply. We can only do *maximum* 600 to 800 round-trips per second. Requests that don't need replies can be batched allowing up to 200,000 requests to be done a second. Consider 20,000 a good guess. That a two-order of magnitude hit for doing an X protocol round-trip. If you examine the trace to find the atoms that are interned, 14 atoms are interned for the SoundScheme protocol (though at most 3 will probably ever be used by iconbook). The desks support requires 5 atoms to be interned (even if desks aren't in use!). Two atoms are interned for using SGI's help protocol even though help hasn't even been requested yet. These 21 InternAtom's represent an (estimated) 1/35 second delay in start up most toto programs. 4) The 170 QueryColors requests seem suspect. The request maps a set of pixel values to RGB triples. Normally this request would be a seldom used request since most clients want to map an RGB triple or color name to a pixel value and not vice versa. But due to a performance bug in the Buffy Motif, QueryColors creates tons of round-trips. Additionally, the request allows multiple pixel values to be mapped to RGB triples but most of the time, QuerColor is sent with a single pixel value. Quite inefficient. 5) The GetGeometry request returns the height, width, and depth of an X drawable (pixmap or window). It is called 30 times (each call generating a round trip). If you examine the protocol trace, GetGeometry is called of only a few requests after the request that created the drawable. One must wonder why the height, width, and depth for a drawable must be retrieved when those parameters had to specified by the program moments before. The answer is a performance bug in Motif. Usually GetGeometry and GetWindowAttributes rarely need to be called. For windows your X client created, it should already know the information. Most of the 20 GetWindowAttributes requests appear to be unnecessary. These are the type of insights that are motivated mostly from the results of xprotostats. [BUGs are filed on the problems discussed above; many of the problems have been fixed though we are still waiting for the fixes to make it into "an alpha near you."] Another use of xprotostats is to see how different alphas affect the number of X requests your application does. If a new alpha comes out, you'll be able to quickly detect and report a performance regression in Motif or Xt or Xlib that has affected your program. xprotostats only gets you started and pointed in the right direction. The real insights come from reading the trace and understanding what's going on. Here are somethings to look for: 1) Duplicated requests, particularly requests that are querying information. 2) Rendering to windows that have not yet been mapped. 3) Pixmaps being created and freed without ever being rendered too. 4) Round-trip requests that are returning information about objects the client created (and should already know the information for). 5) Mapping already mapped windows; unmapping already unmapped windows. 6) Interning of dubious atoms. 7) Repeatedly calling ClearArea on a cleared window. 8) Querying and opening already open fonts. 9) Creating graphics contexts and destroying them without ever using them Digging deeper: once you've isolated a botched protocol sequence, you need to associate the protocol event with what the program is doing. This actually turns out to be difficult but not impossible. The approach I use is to run the program in dbx and also trace the protocol stream using xscope. If you are looking for problems during startup, that helps since the startup will be mostly deterministic. Look for landmark Xlib requests before the sequence you are interested in (things like OpenFont are fairly rare and good canidates for landmarks). Then set dbx breakpoints in the landmark Xlib routines. Once you get to the landmark, then advance carefully by setting breakpoints in routines you expect to hit. You can use the xscope output to follow your progress. When you finally get to the right place, type "where" in dbx and find out what's going on. Another good source of landmarks is to use "par -s -SS -p <pid>" on the dbx'ed process to get system call landmarks. You'll definitely be in Xlib and probably deep in your toolkit or widget set. From the complete stack trace, you should be able to get a good guess what's going on. At this point refer to the source code for Xlib and Xt and Motif and figure out what's going on. The following dbx commands will help you correlate the routines with their source code: for Xlib: directory /hosts/bonnie.wpd/proj/sherwood/isms/x/mit/lib/X for Xt: directory /hosts/bonnie.wpd/proj/sherwood/isms/x/mit/lib/Xt for Motif: directory /hosts/bonnie.wpd/proj/sherwood/isms/motif/src/lib/XmRoxy for ViewKit: directory /hosts/bonnie.wpd/proj/sherwood/isms/vk/vk/src/base directory /hosts/bonnie.wpd/proj/sherwood/isms/vk/vk/src/components Using dbx's "up", "down", and "edit" commands you should be able to figure out what's going on. Experience does help. Future work: I'd like to write some more sophisticated awk scripts that can actually look for certain botched sequences. Other helpful scripts might allow comparisons between two protocol traces so improvements and/or regressions can be noticed. Another helpful thing would be the ability to insert tracing information into the X protocol stream using uninterpreted data section of the X NoOperation request. Someone else might consider a CASE tool that worked by using a special Xlib that saved the protocol right in the library (meaning no psuedo-server was necessary). This would also make it much easier to tie X protocol to your program code. I really hope engineers take this information seriously and make an effort to understand what their X clients are doing. - Mark Kilgard May, 1993 mjk@sgi.com